CloudWatch Logs InsightsでALBのELB 5XX発生時のアクセスログを分析してみた
ALBのアクセスログを Lambdaを利用して CloudWatchLogsに転送し、CloudWatch Logs Insights で分析してみました。
AWSチームのすずきです。
ALBのELB 5XX発生時の解析のため、アクセスログをパース、CloudWatch Logsに転送するLambda関数を用意。 Amazon CloudWatch Logs Insights で可視化する機会がありましたので、紹介させていただきます。
Lambda
パーサー
- Python 3.7 のランタイム、「re」正規表現モジュールを利用しました。
import re RE_TEXT = r""" ^(?P<type>[^ ]*)\u0020 (?P<time>[^ ]*)\u0020 (?P<elb>[^ ]*)\u0020 (?P<client_ip>[^ ]*):(?P<client_port>[0-9]*)\u0020 (?P<target_ip>[^ ]*)[:-](?P<target_port>[0-9]*)\u0020 (?P<request_processing_time>[-.0-9]*)\u0020 (?P<target_processing_time>[-.0-9]*)\u0020 (?P<response_processing_time>[-.0-9]*)\u0020 (?P<elb_status_code>|[-0-9]*)\u0020 (?P<target_status_code>-|[-0-9]*)\u0020 (?P<received_bytes>[-0-9]*)\u0020 (?P<sent_bytes>[-0-9]*)\u0020 \"(?P<request_method>[^ ]*)\u0020 (?P<request_url>[^ ]*)\u0020 (?P<request_http_version>- |[^ ]*)\"\u0020 \"(?P<user_agent>[^\"]*)\"\u0020 (?P<ssl_cipher>[A-Z0-9-]+)\u0020 (?P<ssl_protocol>[A-Za-z0-9.-]*)\u0020 (?P<target_group_arn>[^ ]*)\u0020 \"(?P<trace_id>[^\"]*)\"\u0020 \"(?P<domain_name>[^\"]*)\"\u0020 \"(?P<chosen_cert_arn>[^\"]*)\"\u0020 (?P<matched_rule_priority>[-.0-9]*)\u0020 (?P<request_creation_time>[^ ]*)\u0020 \"(?P<actions_executed>[^\"]*)\"\u0020 \"(?P<redirect_url>[^\"]*)\"\u0020 \"(?P<error_reason>[^\"]*)\" (?P<new_field>.*) """ RE_FORMAT = re.compile(RE_TEXT, flags=re.VERBOSE)
- 正規表現 と カラム名は Amazon Athena のユーザガイドに準拠しました。
Application Load Balancer ログのクエリ
- ALBの機能追加にあわせてアクセスログの仕様も更新されています。追加された項目が 従来のログの末尾以外に追加された場合、正規表現の修正が必要になる点はご留意下さい。
AZ、ELBノードIP
- S3のログファイル名より ELBノードのIPを取得、アベイアビリティゾーンを求めました。
https://dev.classmethod.jp/cloud/aws/add-az-alb-accesslog/
elb_listener_ip = s3key.split('_')[-2]
d = {}
if len(elb_listener_ip) > 4:
d["elb_listener_ip"] = elb_listener_ip
r = ec2.describe_network_interfaces(
Filters=[{'Name':'association.public-ip','Values':[elb_listener_ip]}]
)
if ("NetworkInterfaces" in r):
d["elb_availabilityzone"] = r["NetworkInterfaces"][0]["AvailabilityZone"]
d["elb_private_ip"] = r["NetworkInterfaces"][0]["PrivateIpAddress"]
テスト
Application Load Balancer のアクセスログ に記載された ログサンプルのパースを試みました。
import json log_h2 = 'h2 2018-07-02T22:23:00.186641Z app/my-loadbalancer/50dc6c495c0c9188 10.0.1.252:48160 10.0.0.66:9000 0.000 0.002 0.000 200 200 5 257 "GET https://10.0.2.105:773/ HTTP/2.0" "curl/7.46.0" ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067 "Root=1-58337327-72bd00b0343d75b906739c42" "-" "-" 1 2018-07-02T22:22:48.364000Z "redirect" "https://example.com:80/" "-"' a = RE_FORMAT.match(log_h2).groupdict() a.update(d) print(json.dump(a))
- 出力結果
{
"type": "h2",
"time": "2018-07-02T22:23:00.186641Z",
"elb": "app/my-loadbalancer/50dc6c495c0c9188",
"client_ip": "10.0.1.252",
"client_port": "48160",
"target_ip": "10.0.0.66",
"target_port": "9000",
"request_processing_time": "0.000",
"target_processing_time": "0.002",
"response_processing_time": "0.000",
"elb_status_code": "200",
"target_status_code": "200",
"received_bytes": "5",
"sent_bytes": "257",
"request_method": "GET",
"request_url": "https://10.0.2.105:773/",
"request_http_version": "HTTP/2.0",
"user_agent": "curl/7.46.0",
"ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
"ssl_protocol": "TLSv1.2",
"target_group_arn": "arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067",
"trace_id": "Root=1-58337327-72bd00b0343d75b906739c42",
"domain_name": "-",
"chosen_cert_arn": "-",
"matched_rule_priority": "1",
"request_creation_time": "2018-07-02T22:22:48.364000Z",
"actions_executed": "redirect",
"redirect_url": "https://example.com:80/",
"error_reason": "-",
"new_field": "",
"elb_availabilityzone": "us-east-2a"
"elb_private_ip": "172.xx.xx.xx"
}
ELB 5XX抽出
ターゲットのEC2応答(target_status_code)が「500」台応答を戻さず、ELB(ALB)応答(elb_status_code)が「500」台、ELB 5XX に該当するログレコードのみを抽出します。
if a["elb_status_code"][0:1] == '5':
if not a["target_status_code"][0:1] == '5':
print(json.dumps(a))
正常系のログを除外する事で、CloudWatch Logsのデータ取り込み課金(0.76USD/GB @東京)、Insightsのクエリ課金(スキャンしたデータ 1 GB あたり 0.0076USD)を抑制します。
Loggerは、Lambda標準のものを利用しました。 任意のロググループ、ログストリームを出力先とする場合、CloudWatch Logs の制限 にご注意ください。
CloudWatchLogs
CloudWatchLogs Insight
CloudWatchLogs Insightで、分析対象のロググループと期間を指定して分析を試みました。
- elb_status_code 500〜599までのログを10件抽出
fields @message | sort @time desc | filter elb_status_code like /5\d\d/ | limit 10
- ログ行を指定、詳細を確認可能です。
- アベイアビリティゾーン別の ELB 5XX ログ件数を集計
stats count(elb_availabilityzone) as count_elb_az by elb_availabilityzone | filter elb_status_code like /5\d\d/ | sort count_elb_az desc
- ELBノードIP、actions_executed 別ログ件数を集計
stats count(actions_executed) as count_actions_executed by actions_executed, elb_listener_ip | filter elb_status_code like /5\d\d/ | sort count_actions_executed desc
まとめ
ALBの ELB 5XX エラーを示したアクセスログ、AWSコンソールを利用して簡単に確認する事が可能となりました。
AWS WAF、認証、Lambda などを利用するALBでは、ELB 5XXエラー発生時、原因特定のためにアクセスログ情報が必要となる事があります。 Amazon Athena よりも 簡単に利用しやすい仕組みが必要な場合、今回の仕組みをお試し下さい。
Application Load Balancer のトラブルシューティング
尚、ELB 5XX、及び エラーコード別のエラー件数 については、ALB の CloudWatchのメトリックで確認する事が可能です。 迅速なエラー通知を必要とする場合、こちらを対象としたアラームもお試し下さい。
- ELB 5XX エラーコード一覧
| レスポンスコード | Metric (ALB) | 説明 |
|---|---|---|
| 500-599 | HTTPCode_ELB_5XX_Count | ロードバランサーから送信される HTTP 5XX サーバーエラー |
| 500 | HTTPCode_ELB_500_Count | 内部サーバーエラー |
| 501 | - | Not Implemented |
| 502 | HTTPCode_ELB_502_Count | Bad Gateway |
| 503 | HTTPCode_ELB_503_Count | Service Unavailable |
| 504 | HTTPCode_ELB_504_Count | Gateway Timeout |
| 561 | - | Unauthorized |
CloudFormation
今回紹介したLambda、S3を展開するCloudFormationテンプレートです。
構成図
